Amazon RDS for MySQL でいつからレプリケーションエラーが発生しているかを確認したい

レプリケーションエラーの内容ではなく、それがいつから発生しているかの調査にスポットを当てて書きます。Amazon RDS for MySQLと書いていますが、他のエンジンでも使えるかと思います。

#Amazon RDS

#AWS CLI

#AWS Config

#AWS

千葉幸宏（チバユキ）

2023.06.05

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

コンバンハ、千葉（幸）です。

Amazon RDS for MySQL を「プライマリ1台、レプリカ1台」で運用している際に、レプリカ側でレプリケーションエラーが発生していることがありました。

レプリカインスタンスの「接続とセキュリティ」タブから確認すると、このようになっています。

RDS_Management_Console

これが果たしていつから発生している事象なのか？を調査しようと思った際に、取りうる手段や方法を調べるのに20分くらいかかりました。誰かの20分を節約するためにブログに残しておきます。

なお、このエントリではエラーの原因や解消方法には触れません。あくまで「いつからエラーなのか」を特定することに範囲を限定します。トラブルシューティングの観点について知りたい方は、以下をご参考ください。

Amazon RDS のトラブルシューティング - Amazon Relational Database Service

まとめ

CloudWatch メトリクスReplicaLagが-1になっているかで確認できる
RDS イベントではエラーメッセージも含めて確認できる
- コンソールから確認できるのは最大24時間、AWS CLI であれば過去14日間まで確認できる
AWS Config リソースタイムラインでも確認できるが、リアルタイムではないので参考程度に
aws rds describe-db-instancesでは「いつから」の情報は取得できない

ReplicaLag メトリクスから確認する

おそらく一番手っ取り早いのはCloudWatchメトリクスReplicaLagを確認することです。

If the ReplicaLag metric returns -1, then replication is currently not active.

（日本語版）

ReplicaLag メトリクスにより -1 が返された場合、レプリケーションは現在アクティブではありません。

Working with DB instance read replicas - Amazon Relational Database Service

レプリケーションエラーが発生していればレプリケーションはアクティブではないはずですので、メトリクスで-1が記録され始めたタイミングを確認すると良さそうです。

レプリカインスタンスの詳細画面の「モニタリング」タブから、ReplicaLagメトリクスを確認します。

RDS_Replica_Lag_2nd

一定時期を境にメトリクスが描画されていません。カーソルを合わせてみると、グラフ描画がなされなくなった後は-1が記録されていました。この辺りがエラーの発生タイミングだろう、とあたりをつけられます。

RDS イベントから確認する

別のアプローチとして、RDS コンソールの「イベント」からレプリケーションエラーのイベントを確認する手法もあります。エラーメッセージの内訳も確認できます。

RDS_Event_24_hours

ただし、ここで確認できるイベントは最大で過去24時間分です。それ以前からレプリケーションエラーが発生している場合、ここでは追い切れません。

（なお、インスタンス詳細画面の「ログとイベント」タブ→「最近のイベント」からもイベントが確認できますが、参照できるイベント量はさらに少ないです。）

AWS CLI コマンドであれば最大で過去14日間まで遡って情報を取得できます。レプリケーションエラー発生がその期間内であれば、このコマンドで発生タイミングを確認できます。

describe-events — AWS CLI 2.11.25 Command Reference

リファレンスから引用したOutput例は以下です。

{
    "Events": [
        {
            "SourceType": "db-instance",
            "SourceIdentifier": "test-instance",
            "EventCategories": [
                "backup"
            ],
            "Message": "Backing up DB instance",
            "Date": "2018-07-31T23:09:23.983Z",
            "SourceArn": "arn:aws:rds:us-east-1:123456789012:db:test-instance"
        },
        {
            "SourceType": "db-instance",
            "SourceIdentifier": "test-instance",
            "EventCategories": [
                "backup"
            ],
            "Message": "Finished DB Instance backup",
            "Date": "2018-07-31T23:15:13.049Z",
            "SourceArn": "arn:aws:rds:us-east-1:123456789012:db:test-instance"
        }
    ]
}

特定のインスタンスを指定し、「14日前から」「カテゴリがread replicaのものを」「イベントの日時のみ」5個取得する例です。

$ aws rds describe-events\
  --source-identifier DB_INSTANCE_NAME\
  --source-type db-instance\
  --start-time $(date -v -14d "+%Y-%m-%dT%H:%M:%SZ")\
  --event-categories "read replica"\
  --query 'Events[].Date'\
  --max-items 5
[
    "2023-05-30T05:05:29.747000+00:00",
    "2023-05-30T05:06:29.774000+00:00",
    "2023-05-30T05:07:29.759000+00:00",
    "2023-05-30T05:08:29.762000+00:00",
    "2023-05-30T05:09:29.759000+00:00"
]

古い順にイベントが取得できるため、14日以内であれば発生タイミングを特定できます。

イベントのメッセージも確認したい場合は例えば以下のように指定できます。

$ aws rds describe-events\
  --source-identifier DB_INSTANCE_NAME\
  --source-type db-instance\
  --duration 20160\
  --event-categories "read replica"\
  --query 'Events[].[Date,Message]'\
  --output text\
  --max-items 5
2023-05-30T05:05:29.747000+00:00        Read Replica Replication Error -  SQLError:  1292, reason:  Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略;
2023-05-30T05:06:29.774000+00:00        Read Replica Replication Error -  SQLError:  1292, reason:  Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略;
2023-05-30T05:07:29.759000+00:00        Read Replica Replication Error -  SQLError:  1292, reason:  Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略;

↑「N日前」の指定は--start-timeでなく--durationでも指定できます。上の例では、60 * 24 * 14 = 20160 分で指定しています。

メトリクスとあわせて確認すれば、より精度の高い情報が得られるでしょう。

AWS Config リソースタイムラインから確認する

あえてこの手法を使うメリットがあるかと言われると微妙ですが、AWS Config のリソースタイムラインからでもステータスの変わったタイミングが確認できます。

AWS Config コンソール「リソース」で以下を指定してフィルタリングし、対象のリソースを選択して「リソースタイムライン」を表示します。

リソースカテゴリ：AWS リソース
リソースタイプ：AWS RDS DBInstance
リソース識別子：（レプリカインスタンス名）

タイムラインの表示イメージはこちら。レプリケーションのステータスが変わったタイミングが記録されています。

AWS_Config_timeline

ただ、AWS Config による記録はリアルタイムで行われているわけではないので、ここで確認できる日時は参考程度にとどめておいた方が良さそうです。

今回のケースでは、「RDSイベントでレプリケーションエラーが記録され始めたタイミング」と「リソースタイムライン上でレプリケーションステータスの変更が記録されたタイミング」は21時間ほどズレがありました。

余談：describe-db-instances では「いつから」はわからない

ここまでのいずれかの手法で、「いつからレプリケーションエラーが発生しているか」は概ね特定できているはずです。

それらの手法とは異なり発生タイミングは取得できないのですが、参考までに DB インスタンスの詳細を表示する AWS CLI コマンドも試しておきます。

describe-db-instances — AWS CLI 2.11.25 Command Reference

実行例は以下です。対象に指定しているのはレプリカインスタンスです。（DBインスタンスのパラメータ多いな！というのに気付かされます。）

$ aws rds describe-db-instances --db-instance-identifier DB-INSTANCE-NAME
{
    "DBInstances": [
        {
            "DBInstanceIdentifier": "DB-INSTANCE-NAME",
            "DBInstanceClass": "db.r5.large",
            "Engine": "mysql",
            "DBInstanceStatus": "available",
            "MasterUsername": "username",
            "DBName": "dbname",
            "Endpoint": {
                "Address": "DB-INSTANCE-NAME.xxxxxxxx.ap-northeast-1.rds.amazonaws.com",
                "Port": 3306,
                "HostedZoneId": "xxxxxxxx"
            },
            "AllocatedStorage": 2500,
            "InstanceCreateTime": "2015-03-10T05:22:35.905000+00:00",
            "PreferredBackupWindow": "05:00-05:30",
            "BackupRetentionPeriod": 0,
            "DBSecurityGroups": [],
            "VpcSecurityGroups": [
                {
                    "VpcSecurityGroupId": "sg-xxxxxxxx",
                    "Status": "active"
                }
            ],
            "DBParameterGroups": [
                {
                    "DBParameterGroupName": "mysql5-7",
                    "ParameterApplyStatus": "in-sync"
                }
            ],
            "AvailabilityZone": "ap-northeast-1a",
            "DBSubnetGroup": {
                "DBSubnetGroupName": "sb-gp",
                "DBSubnetGroupDescription": "sb-gp",
                "VpcId": "vpc-xxxxxxxx",
                "SubnetGroupStatus": "Complete",
                "Subnets": [
                    {
                        "SubnetIdentifier": "subnet-xxxxxxxx",
                        "SubnetAvailabilityZone": {
                            "Name": "ap-northeast-1a"
                        },
                        "SubnetOutpost": {},
                        "SubnetStatus": "Active"
                    },
                    {
                        "SubnetIdentifier": "subnet-xxxxxxxx",
                        "SubnetAvailabilityZone": {
                            "Name": "ap-northeast-1c"
                        },
                        "SubnetOutpost": {},
                        "SubnetStatus": "Active"
                    }
                ]
            },
            "PreferredMaintenanceWindow": "sat:06:00-sat:06:30",
            "PendingModifiedValues": {},
            "MultiAZ": false,
            "EngineVersion": "5.7.38",
            "AutoMinorVersionUpgrade": true,
            "ReadReplicaSourceDBInstanceIdentifier": "SOURCE_INSTANCE_NAME",
            "ReadReplicaDBInstanceIdentifiers": [],
            "LicenseModel": "general-public-license",
            "OptionGroupMemberships": [
                {
                    "OptionGroupName": "default:mysql-5-7",
                    "Status": "in-sync"
                }
            ],
            "PubliclyAccessible": false,
            "StatusInfos": [
                {
                    "StatusType": "read replication",
                    "Normal": false,
                    "Status": "error",
                    "Message": "Apply Error 1292: Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略"
                }
            ],
            "StorageType": "gp2",
            "DbInstancePort": 0,
            "StorageEncrypted": false,
            "DbiResourceId": "db-XXXXXXXXXX",
            "CACertificateIdentifier": "rds-ca-2019",
            "DomainMemberships": [],
            "CopyTagsToSnapshot": false,
            "MonitoringInterval": 0,
            "DBInstanceArn": "arn:aws:rds:ap-northeast-1:000000000000:db:DB-INSTANCE-NAME",
            "IAMDatabaseAuthenticationEnabled": false,
            "DeletionProtection": false,
            "AssociatedRoles": [],
            "TagList": [
                {
                    "Key": "Test",
                    "Value": "Test"
                }
            ],
            "CustomerOwnedIpEnabled": false,
            "ActivityStreamStatus": "stopped",
            "BackupTarget": "region",
            "NetworkType": "IPV4"
        }
    ]
}

ステータスに関連する部分だけ抽出します。

$ aws rds describe-db-instances --db-instance-identifier DB-INSTANCE-NAME\
  --query 'DBInstances[].StatusInfos'
[
    [
        {
            "StatusType": "read replication",
            "Normal": false,
            "Status": "error",
            "Message": "Apply Error 1292: Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略"
        }
    ]
]

ステータスでエラーが発生していることは分かりますが、それがいつからなのかはこのコマンドでは取得できません。このコマンドで取得できるのとほぼ同等の内容は AWS Config によって定期的に収集されていますので、値の変化の記録は Config の役割である、と言えるかもしれません。